Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tweak timing information #7

Open
wants to merge 3 commits into
base: master
Choose a base branch
from
Open

tweak timing information #7

wants to merge 3 commits into from

Conversation

jameinel
Copy link

This adds a few small changes to the logging. It adds "in %.6fs" to the response message, which lets you see how long each request is served. You can almost extract that from the existing messages (with UnixNano), but it requires math, which is hard to do in a big log file.
Also, the Request is only after we've already done some checksumming of the user request, and I wanted that in the timing.

In running on my machine, most requests can be served in 50us or so, but occasionally you'll even get up to 180ms. I'm guessing those are times when the garbage collector kicked in.

On my machine (with 4 real cores) I get throttled at about 230% CPU, with rsyslog taking another 100%CPU, and I'm getting 500k requests served in 30s (16.6k reqs/second) (I tried it with big curl loops, and ab test gives similar results). 6ms average request response.

I have a profiling branch (not submitted here), which says that we're spending 33% of our time in Syscall trying to read network data (possibly also reading /dev/urandom?), 12% of the time doing Fprintf stuff (probably explains all the GC), and 15% of the time in syslog.Info, we actually spend only about 3% of the time doing actual sha 512 stuff. (If I disable syslog, I only get to 19k reqs/second, if I make the inner ServeHTTP a simple write data and return it is also 19k reqs/second so the rest of the overhead is in HTTP lib stuff.)

Anyway, this is a small tweak, if you like it.

@jameinel
go fmt, and some formatting tweaks
17070d9 
when using fatal it wasn't appending a newline, so messages were confusing
this fixes that.
also, add millisecond-level timing for how long it takes us to respond
to requests. The *data* is available in UnixNano() but it requires
doing the subtraction somehow, and also misses some of the overhead
as the 'received challenge' only triggers after we've processed
some of the request.
@jameinel
actually do the right formatting
055ed37
@jameinel
use microsecond timing (ms was always 0)
cd0117f 
also, add a log when the process starts
@dustinkirkland
Copy link
Owner

Thanks again, John.

It looks like all of this functionality (I hand checked it) was included
and committed in the previous pull request.

I made one very minor tweak, putting the timing information inside of
[brackets] to match the rest of my logging format.

Thanks!

Dustin Kirkland
Canonical, Ltd.

On Wed, Feb 26, 2014 at 8:14 AM, John Arbash Meinel <
[email protected]> wrote:

This adds a few small changes to the logging. It adds "in %.6fs" to the
response message, which lets you see how long each request is served. You
can almost extract that from the existing messages (with UnixNano), but it
requires math, which is hard to do in a big log file.
Also, the Request is only after we've already done some checksumming of
the user request, and I wanted that in the timing.

In running on my machine, most requests can be served in 50us or so, but
occasionally you'll even get up to 180ms. I'm guessing those are times when
the garbage collector kicked in.

On my machine (with 4 real cores) I get throttled at about 230% CPU, with
rsyslog taking another 100%CPU, and I'm getting 500k requests served in 30s
(16.6k reqs/second) (I tried it with big curl loops, and ab test gives
similar results). 6ms average request response.

I have a profiling branch (not submitted here), which says that we're
spending 33% of our time in Syscall trying to read network data (possibly
also reading /dev/urandom?), 12% of the time doing Fprintf stuff (probably
explains all the GC), and 15% of the time in syslog.Info, we actually spend
only about 3% of the time doing actual sha 512 stuff. (If I disable syslog,
I only get to 19k reqs/second, if I make the inner ServeHTTP a simple write
data and return it is also 19k reqs/second so the rest of the overhead is
in HTTP lib stuff.)

Anyway, this is a small tweak, if you like it.

You can merge this Pull Request by running

git pull https://github.com/jameinel/pollen timing

Or view, comment on, or merge it at:

#7
Commit Summary

  • go fmt, and some formatting tweaks
  • actually do the right formatting
  • use microsecond timing (ms was always 0)

File Changes

Patch Links:

Reply to this email directly or view it on GitHubhttps://github.com//pull/7
.

@jameinel
Copy link
Author

Yeah. I ended up having to merge them because they changed similar lines so
caused conflicts.

Thanks for merging it.

John
=:->
On Feb 26, 2014 8:40 PM, "Dustin Kirkland" [email protected] wrote:

Thanks again, John.

It looks like all of this functionality (I hand checked it) was included
and committed in the previous pull request.

I made one very minor tweak, putting the timing information inside of
[brackets] to match the rest of my logging format.

Thanks!

Dustin Kirkland
Canonical, Ltd.

On Wed, Feb 26, 2014 at 8:14 AM, John Arbash Meinel <
[email protected]> wrote:

This adds a few small changes to the logging. It adds "in %.6fs" to the
response message, which lets you see how long each request is served. You
can almost extract that from the existing messages (with UnixNano), but
it
requires math, which is hard to do in a big log file.
Also, the Request is only after we've already done some checksumming of
the user request, and I wanted that in the timing.

In running on my machine, most requests can be served in 50us or so, but
occasionally you'll even get up to 180ms. I'm guessing those are times
when
the garbage collector kicked in.

On my machine (with 4 real cores) I get throttled at about 230% CPU, with
rsyslog taking another 100%CPU, and I'm getting 500k requests served in
30s
(16.6k reqs/second) (I tried it with big curl loops, and ab test gives
similar results). 6ms average request response.

I have a profiling branch (not submitted here), which says that we're
spending 33% of our time in Syscall trying to read network data (possibly
also reading /dev/urandom?), 12% of the time doing Fprintf stuff
(probably
explains all the GC), and 15% of the time in syslog.Info, we actually
spend
only about 3% of the time doing actual sha 512 stuff. (If I disable
syslog,
I only get to 19k reqs/second, if I make the inner ServeHTTP a simple
write
data and return it is also 19k reqs/second so the rest of the overhead is
in HTTP lib stuff.)

Anyway, this is a small tweak, if you like it.

You can merge this Pull Request by running

git pull https://github.com/jameinel/pollen timing

Or view, comment on, or merge it at:

#7
Commit Summary

  • go fmt, and some formatting tweaks
  • actually do the right formatting
  • use microsecond timing (ms was always 0)

File Changes

Patch Links:

Reply to this email directly or view it on GitHub<
https://github.com/dustinkirkland/pollen/pull/7>
.

—
Reply to this email directly or view it on GitHubhttps://github.com//pull/7#issuecomment-36145923
.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers
No reviews
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.
2 participants
@jameinel @dustinkirkland